2017/01/14 02:46:58 [debug] 14576#0: *358792 accept: X.X.X.X:51644 fd:117
2017/01/14 02:46:58 [debug] 14576#0: *358792 event timer add: 117: 60000:1484362078365
2017/01/14 02:46:58 [debug] 14576#0: *358792 reusable connection: 1
2017/01/14 02:46:58 [debug] 14576#0: *358792 epoll add event: fd:117 op:1 ev:80002001
2017/01/14 02:46:58 [debug] 14576#0: *358792 post event 00007F2ECE033C10
2017/01/14 02:46:58 [debug] 14576#0: *358792 delete posted event 00007F2ECE033C10
2017/01/14 02:46:58 [debug] 14576#0: *358792 http check ssl handshake
2017/01/14 02:46:58 [debug] 14576#0: *358792 http recv(): 1
2017/01/14 02:46:58 [debug] 14576#0: *358792 https ssl handshake: 0x16
2017/01/14 02:46:58 [debug] 14576#0: *358792 SSL server name: "A.B.C"
2017/01/14 02:46:58 [debug] 14576#0: *358792 SSL_do_handshake: -1
2017/01/14 02:46:58 [debug] 14576#0: *358792 SSL_get_error: 2
2017/01/14 02:46:58 [debug] 14576#0: *358792 reusable connection: 0
2017/01/14 02:46:58 [debug] 14576#0: *358792 SSL handshake handler: 0
2017/01/14 02:46:58 [debug] 14576#0: *358792 SSL_do_handshake: -1
2017/01/14 02:46:58 [debug] 14576#0: *358792 SSL_get_error: 2
2017/01/14 02:46:58 [debug] 14576#0: *358792 post event 00007F2ECE033C10
2017/01/14 02:46:58 [debug] 14576#0: *358792 delete posted event 00007F2ECE033C10
2017/01/14 02:46:58 [debug] 14576#0: *358792 SSL handshake handler: 0
2017/01/14 02:46:58 [debug] 14576#0: *358792 SSL_do_handshake: 1
2017/01/14 02:46:58 [debug] 14576#0: *358792 SSL: TLSv1, cipher: “cipher1”
2017/01/14 02:46:58 [debug] 14576#0: *358792 reusable connection: 1
2017/01/14 02:46:58 [debug] 14576#0: *358792 http wait request handler
2017/01/14 02:46:58 [debug] 14576#0: *358792 malloc: 0000000004EC3890:1024
2017/01/14 02:46:58 [debug] 14576#0: *358792 SSL_read: -1
2017/01/14 02:46:58 [debug] 14576#0: *358792 SSL_get_error: 2
2017/01/14 02:46:58 [debug] 14576#0: *358792 free: 0000000004EC3890
2017/01/14 02:46:59 [debug] 14576#0: *358792 http wait request handler
2017/01/14 02:46:59 [debug] 14576#0: *358792 malloc: 00000000050FFC60:1024
2017/01/14 02:46:59 [debug] 14576#0: *358792 SSL_read: 455
2017/01/14 02:46:59 [debug] 14576#0: *358792 SSL_read: 0
2017/01/14 02:46:59 [debug] 14576#0: *358792 SSL_get_error: 6
2017/01/14 02:46:59 [debug] 14576#0: *358792 peer shutdown SSL cleanly
2017/01/14 02:46:59 [debug] 14576#0: *358792 reusable connection: 0
2017/01/14 02:46:59 [debug] 14576#0: *358792 posix_memalign: 00000000050F7CE0:4096 @16
2017/01/14 02:46:59 [debug] 14576#0: *358792 http process request line
2017/01/14 02:46:59 [debug] 14576#0: *358792 http request line: "POST /X/Y/Z?k1=v1&k2=v2 HTTP/1.1"
2017/01/14 02:46:59 [debug] 14576#0: *358792 http uri: “X/Y/Z”
2017/01/14 02:46:59 [debug] 14576#0: *358792 http args: "k1=v1&k2=v2"
2017/01/14 02:46:59 [debug] 14576#0: *358792 http exten: ""
2017/01/14 02:46:59 [debug] 14576#0: *358792 posix_memalign: 0000000003F42E70:4096 @16
2017/01/14 02:46:59 [debug] 14576#0: *358792 http process request header line
2017/01/14 02:46:59 [debug] 14576#0: *358792 http header: "Content-Type: application/octet-stream"
2017/01/14 02:46:59 [debug] 14576#0: *358792 http header: "content-encoding: gzip"
2017/01/14 02:46:59 [debug] 14576#0: *358792 http header: "Host: A.B.C"
2017/01/14 02:46:59 [debug] 14576#0: *358792 http header: "Content-Length: 45"
2017/01/14 02:46:59 [debug] 14576#0: *358792 http header: "Expect: 100-continue"
2017/01/14 02:46:59 [debug] 14576#0: *358792 http header: "Connection: Keep-Alive"
2017/01/14 02:46:59 [debug] 14576#0: *358792 http header done
2017/01/14 02:46:59 [debug] 14576#0: *358792 event timer del: 117: 1484362078365
2017/01/14 02:46:59 [debug] 14576#0: *358792 generic phase: 0
2017/01/14 02:46:59 [debug] 14576#0: *358792 rewrite phase: 1
2017/01/14 02:46:59 [debug] 14576#0: *358792 http cleanup add: 00000000050F8C98
2017/01/14 02:46:59 [debug] 14576#0: *358792 http script value (post filter): "01010101010101010101010101010101"
…
2017/01/14 02:46:59 [debug] 14576#0: *358792 lua reset ctx
…
2017/01/14 02:46:59 [debug] 14576#0: *358792 test location: "/"
2017/01/14 02:46:59 [debug] 14576#0: *358792 test location: “a/b”
2017/01/14 02:46:59 [debug] 14576#0: *358792 test location: “c/d/“
2017/01/14 02:46:59 [debug] 14576#0: *358792 test location: “f”
2017/01/14 02:46:59 [debug] 14576#0: *358792 test location: “g”
2017/01/14 02:46:59 [debug] 14576#0: *358792 using configuration "/"
2017/01/14 02:46:59 [debug] 14576#0: *358792 http cl:45 max:1048576
2017/01/14 02:46:59 [debug] 14576#0: *358792 rewrite phase: 3
2017/01/14 02:46:59 [debug] 14576#0: *358792 http script var
2017/01/14 02:46:59 [debug] 14576#0: *358792 http script regex: "^Abc$"
2017/01/14 02:46:59 [notice] 14576#0: *358792 "^Abc$" does not match "", client: X.X.X.X, server: A.B.C, request: "POST /X/Y/Z?k1=v1&k2=v2 HTTP/1.1", host: "A.B.C"
2017/01/14 02:46:59 [debug] 14576#0: *358792 http script if
2017/01/14 02:46:59 [debug] 14576#0: *358792 http script if: false
2017/01/14 02:46:59 [debug] 14576#0: *358792 rewrite phase: 4
2017/01/14 02:46:59 [debug] 14576#0: *358792 headers more rewrite handler, uri “/X/Y/Z”
2017/01/14 02:46:59 [debug] 14576#0: *358792 post rewrite phase: 5
2017/01/14 02:46:59 [debug] 14576#0: *358792 generic phase: 6
2017/01/14 02:46:59 [debug] 14576#0: *358792 generic phase: 7
2017/01/14 02:46:59 [debug] 14576#0: *358792 generic phase: 8
2017/01/14 02:46:59 [debug] 14576#0: *358792 access phase: 9
2017/01/14 02:46:59 [debug] 14576#0: *358792 access phase: 10
2017/01/14 02:46:59 [debug] 14576#0: *358792 post access phase: 11
2017/01/14 02:46:59 [debug] 14576#0: *358792 send 100 Continue
2017/01/14 02:46:59 [debug] 14576#0: *358792 SSL to write: 25
2017/01/14 02:46:59 [debug] 14576#0: *358792 SSL_write: -1
2017/01/14 02:46:59 [debug] 14576#0: *358792 SSL_get_error: 5
2017/01/14 02:46:59 [info] 14576#0: *358792 SSL_write() failed (SSL:) (32: Broken pipe), client: X.X.X.X, server: A.B.C, request: "POST /X/Y/Z?k1=v1&k2=v2 HTTP/1.1", host: "A.B.C"
2017/01/14 02:46:59 [debug] 14576#0: *358792 http finalize request: 500, "/X/Y/Z?k1=v1&k2=v2" a:1, c:1
2017/01/14 02:46:59 [debug] 14576#0: *358792 http special response: 500, "/X/Y/Z?k1=v1&k2=v2"
2017/01/14 02:46:59 [debug] 14576#0: *358792 minutes: "/static/error/500.html?"
2017/01/14 02:46:59 [debug] 14576#0: *358792 rewrite phase: 1
2017/01/14 02:46:59 [debug] 14576#0: *358792 posix_memalign: 00000000036573A0:4096 @16
2017/01/14 02:46:59 [debug] 14576#0: *358792 http cleanup add: 0000000003F43DC0
2017/01/14 02:46:59 [debug] 14576#0: *358792 http script value (post filter): "01010101010101010101010101010101"
…
2017/01/14 02:46:59 [debug] 14576#0: *358792 test location: "/"
2017/01/14 02:46:59 [debug] 14576#0: *358792 test location: “a/b”
2017/01/14 02:46:59 [debug] 14576#0: *358792 test location: “c/d/“
2017/01/14 02:46:59 [debug] 14576#0: *358792 test location: "static"
2017/01/14 02:46:59 [debug] 14576#0: *358792 test location: “/f”
2017/01/14 02:46:59 [debug] 14576#0: *358792 using configuration "/static/error"
2017/01/14 02:46:59 [debug] 14576#0: *358792 http cl:45 max:1048576
2017/01/14 02:46:59 [debug] 14576#0: *358792 rewrite phase: 3
2017/01/14 02:46:59 [debug] 14576#0: *358792 rewrite phase: 4
2017/01/14 02:46:59 [debug] 14576#0: *358792 headers more rewrite handler, uri "/static/error/500.html"
2017/01/14 02:46:59 [debug] 14576#0: *358792 post rewrite phase: 5
2017/01/14 02:46:59 [debug] 14576#0: *358792 generic phase: 6
2017/01/14 02:46:59 [debug] 14576#0: *358792 generic phase: 7
2017/01/14 02:46:59 [debug] 14576#0: *358792 generic phase: 8
2017/01/14 02:46:59 [debug] 14576#0: *358792 access phase: 9
2017/01/14 02:46:59 [debug] 14576#0: *358792 access phase: 10
2017/01/14 02:46:59 [debug] 14576#0: *358792 post access phase: 11
2017/01/14 02:46:59 [debug] 14576#0: *358792 content phase: 12
2017/01/14 02:46:59 [debug] 14576#0: *358792 content phase: 13
2017/01/14 02:46:59 [debug] 14576#0: *358792 content phase: 14
2017/01/14 02:46:59 [debug] 14576#0: *358792 content phase: 15
2017/01/14 02:46:59 [debug] 14576#0: *358792 http filename: "/static/error/500.html"
2017/01/14 02:46:59 [debug] 14576#0: *358792 add cleanup: 0000000003657640
2017/01/14 02:46:59 [debug] 14576#0: *358792 http static fd: 136
2017/01/14 02:46:59 [debug] 14576#0: *358792 http set discard body
2017/01/14 02:46:59 [debug] 14576#0: *358792 http read discarded body
2017/01/14 02:46:59 [debug] 14576#0: *358792 ngx_http_streaming_header_filter()
2017/01/14 02:46:59 [debug] 14576#0: *358792 ip tos: 0x80
2017/01/14 02:46:59 [debug] 14576#0: *358792 headers more header filter, uri "/static/error/500.html"
…
2017/01/14 02:46:59 [debug] 14576#0: *358792 lua header filter for user lua code, uri "/static/error/500.html"
2017/01/14 02:46:59 [debug] 14576#0: *358792 lua capture header filter, uri "/static/error/500.html"
2017/01/14 02:46:59 [debug] 14576#0: *358792 HTTP/1.1 500 Internal Server Error
2017/01/14 02:46:59 [debug] 14576#0: *358792 write new buf t:1 f:0 0000000003657930, pos 0000000003657930, size: 300 file: 0, size: 0
2017/01/14 02:46:59 [debug] 14576#0: *358792 http write filter: l:0 f:0 s:300
2017/01/14 02:46:59 [debug] 14576#0: *358792 http output filter "/static/error/500.html?"
2017/01/14 02:46:59 [debug] 14576#0: *358792 http copy filter: "/static/error/500.html?"
2017/01/14 02:46:59 [debug] 14576#0: *358792 malloc: 0000000004E14180:14343
2017/01/14 02:46:59 [debug] 14576#0: *358792 read: 136, 0000000004E14180, 14343, 0
2017/01/14 02:46:59 [debug] 14576#0: *358792 ngx_http_streaming_body_filter()
2017/01/14 02:46:59 [debug] 14576#0: *358792 lua capture body filter, uri "/static/error/500.html"
2017/01/14 02:46:59 [debug] 14576#0: *358792 http postpone filter "/static/error/500.html?" 0000000003657B58
2017/01/14 02:46:59 [debug] 14576#0: *358792 write old buf t:1 f:0 0000000003657930, pos 0000000003657930, size: 300 file: 0, size: 0
2017/01/14 02:46:59 [debug] 14576#0: *358792 write new buf t:1 f:0 0000000004E14180, pos 0000000004E14180, size: 14343 file: 0, size: 0
2017/01/14 02:46:59 [debug] 14576#0: *358792 http write filter: l:1 f:0 s:14643
2017/01/14 02:46:59 [debug] 14576#0: *358792 http write filter limit 0
2017/01/14 02:46:59 [debug] 14576#0: *358792 posix_memalign: 0000000003FD5F10:512 @16
2017/01/14 02:46:59 [debug] 14576#0: *358792 malloc: 0000000003D15350:16384
2017/01/14 02:46:59 [debug] 14576#0: *358792 SSL buf copy: 300
2017/01/14 02:46:59 [debug] 14576#0: *358792 SSL buf copy: 14343
2017/01/14 02:46:59 [debug] 14576#0: *358792 SSL to write: 14643
2017/01/14 02:46:59 [debug] 14576#0: *358792 SSL_write: -1
2017/01/14 02:46:59 [debug] 14576#0: *358792 SSL_get_error: 1
2017/01/14 02:46:59 [crit] 14576#0: *358792 SSL_write() failed (SSL: error:1409F07F:SSL routines:ssl3_write_pending:bad write retry) while sending response to client, client: X.X.X.X, server: A.B.C, request: "POST /X/Y/Z?k1=v1&k2=v2 HTTP/1.1", host: "A.B.C"
2017/01/14 02:46:59 [debug] 14576#0: *358792 http write filter FFFFFFFFFFFFFFFF
2017/01/14 02:46:59 [debug] 14576#0: *358792 http copy filter: -1 "/static/error/500.html?"
2017/01/14 02:46:59 [debug] 14576#0: *358792 http finalize request: -1, "/static/error/500.html?" a:1, c:2
2017/01/14 02:46:59 [debug] 14576#0: *358792 http terminate request count:2
2017/01/14 02:46:59 [debug] 14576#0: *358792 lua request cleanup: forcible=0
2017/01/14 02:46:59 [debug] 14576#0: *358792 lua request cleanup: forcible=0
2017/01/14 02:46:59 [debug] 14576#0: *358792 http terminate cleanup count:2 blk:0
2017/01/14 02:46:59 [debug] 14576#0: *358792 http finalize request: -4, "/static/error/500.html?" a:1, c:2
2017/01/14 02:46:59 [debug] 14576#0: *358792 http request count:2 blk:0
2017/01/14 02:46:59 [debug] 14576#0: *358792 http posted request: "/static/error/500.html?"
2017/01/14 02:46:59 [debug] 14576#0: *358792 http terminate handler count:1
2017/01/14 02:46:59 [debug] 14576#0: *358792 http request count:1 blk:0
2017/01/14 02:46:59 [debug] 14576#0: *358792 http close request
2017/01/14 02:46:59 [debug] 14576#0: *358792 lua log handler, uri:"/static/error/500.html" c:0
2017/01/14 02:46:59 [debug] 14576#0: *358792 http log handler
2017/01/14 02:46:59 [debug] 14576#0: *358792 run cleanup: 0000000003657640
2017/01/14 02:46:59 [debug] 14576#0: *358792 file cleanup: fd:136
2017/01/14 02:46:59 [debug] 14576#0: *358792 free: 0000000004E14180
2017/01/14 02:46:59 [debug] 14576#0: *358792 free: 00000000050F7CE0, unused: 0
2017/01/14 02:46:59 [debug] 14576#0: *358792 free: 0000000003F42E70, unused: 0
2017/01/14 02:46:59 [debug] 14576#0: *358792 free: 00000000036573A0, unused: 1448
2017/01/14 02:46:59 [debug] 14576#0: *358792 close http connection: 117
2017/01/14 02:46:59 [debug] 14576#0: *358792 SSL_shutdown: 1
2017/01/14 02:46:59 [debug] 14576#0: *358792 reusable connection: 0
2017/01/14 02:46:59 [debug] 14576#0: *358792 free: 0000000003D15350
2017/01/14 02:46:59 [debug] 14576#0: *358792 free: 00000000050FFC60
2017/01/14 02:46:59 [debug] 14576#0: *358792 free: 0000000003F390C0, unused: 8
2017/01/14 02:46:59 [debug] 14576#0: *358792 free: 0000000003FD5F10, unused: 384
